Lambda関数のhandlerの外側でRDS Proxyの接続をした場合の処理時間を計測してみた

RDS Proxyの接続を使い回した場合の影響を知りたい

こんにちは、のんピ(@non____97)です。

以下記事でLambda関数からRDS Proxy経由でAmazon Aurora DBクラスターに接続してみました。

その際のLambda関数ではRDS Proxyの接続をhandler内で行っており、Lambda関数を実行するたびにRDS Proxyに接続をしていました 。

RDS Proxyの接続をhandlerの外側にした場合は、RDS Proxyの接続を維持することができ、ウォームスタート時には接続処理をスキップできるためパフォーマンスの向上が期待できます。

参考:

この情報を見て、「実際Lambda関数のhandlerの外側でRDS Proxyの接続をすると処理時間にどのぐらい影響を与えるのか」が非常に気になったので検証してみます。

こちらのコードのリポジトリは以下になります。

使用するLambda関数

RDS Proxyの接続をhandlerの外側で実行するLambda関数と、内側で実行するLambda関数を用意しました。

RDS Proxyの接続をhandlerの内側で実行するLambda関数はコネクションのクローズもhandler内で行っています。

import { getSecretValue } from "../utils/getSecretValue";
import { dbConnect } from "../utils/dbConnect";
import { QueryResult } from "../utils/table";

const secret = await getSecretValue();
const dbClient = await dbConnect(secret);

export const handler = async (): Promise<QueryResult | Error> => {
  // Query
  const beforeInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(beforeInsertQuery.rows);

  await dbClient.query("INSERT INTO test_table (name) VALUES ('non-97')");

  const afterInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(afterInsertQuery.rows);

  return {
    beforeInsertQueryRows: beforeInsertQuery.rows,
    afterInsertQueryRows: afterInsertQuery.rows,
  };
};

import { getSecretValue } from "../utils/getSecretValue";
import { dbConnect } from "../utils/dbConnect";
import { QueryResult } from "../utils/table";

const secret = await getSecretValue();

export const handler = async (): Promise<QueryResult | Error> => {
  const dbClient = await dbConnect(secret);

  // Query
  const beforeInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(beforeInsertQuery.rows);

  await dbClient.query("INSERT INTO test_table (name) VALUES ('non-97')");

  const afterInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(afterInsertQuery.rows);

  dbClient.end();

  return {
    beforeInsertQueryRows: beforeInsertQuery.rows,
    afterInsertQueryRows: afterInsertQuery.rows,
  };
};

Prepared Statementsでクエリを発行してしまうとピン留めされてしまうので、Prepared Statementsは使用しません。ピン留めについては以下記事とAWS公式ドキュメントをご覧ください。

また、こちらのLambda関数ではtop-level awaitを使用しています。

そのため、ターゲットはtop-level awaitをサポートしているv14.8以降を指定し、フォーマットはCommonJSではなくES Modulesにしています。 また、インポートするモジュールをNodejsFunction側でも明示的に指定する必要があったのでnodeModulesでLambda関数で使用するモジュールを指定してあげます。

new nodejs.NodejsFunction(this, "DbAccessDbconnectOutsideHandlerFunction", {
  entry: path.join(
    __dirname,
    "../src/lambda/handlers/db-access-dbconnect-outside-handler.ts"
  ),
  runtime: lambda.Runtime.NODEJS_14_X,
  bundling: {
    minify: true,
    sourceMap: true,
    externalModules: ["pg-native"],
    target: "node14.19",
    tsconfig: path.join(__dirname, "../src/lambda/tsconfig.json"),
    format: nodejs.OutputFormat.ESM,
    nodeModules: ["@aws-sdk/client-secrets-manager", "pg"],
  },
  environment: {
    PROXY_ENDPOINT: rdsProxy.endpoint,
    SECRET_ID: dbAdminSecret.secretArn,
    NODE_OPTIONS: "--enable-source-maps",
  },
  role: dbAccessFunctionIamRole,
  logRetention: logs.RetentionDays.TWO_WEEKS,
  tracing: lambda.Tracing.ACTIVE,
  securityGroups: [dbClientSg],
  vpc,
  vpcSubnets: vpc.selectSubnets({
    subnetType: ec2.SubnetType.PRIVATE_WITH_NAT,
  }),
});

top-level awaitを使用するには以下の条件を満たす必要があります。

• moduleオプションが以下のいずれか
  • es2022
  • esnext
  • system
  • nodenext
• targetオプションが以下のバージョン以上
  • es2017

こちらの条件を満たすようにLambda関数のトランスコンパイルに使用するtsconfig.jsonを用意してあげます。

{
  "extends": "../../tsconfig.json",
  "compilerOptions": {
    "target": "es2019",
    "module": "es2022",
    "moduleResolution": "node",
    "allowSyntheticDefaultImports": true,
    "esModuleInterop":true
  }
}

計測してみた

計測のレギュレーション

計測するにあたってのレギュレーションは以下の通りです。

• メモリを128MB割り当てたLambda関数からRDS Proxy経由でAurora DBクラスターに接続
• Lambda関数から簡単なSQL(SELECTとINSERT)を発行
• 計測は以下の状態で行う
  • DBのテーブルがクリアされている
  • RDS ProxyとAurora DBクラスター間のコネクションが無い
  • Lambda関数とRDS Proxy間のコネクションが無い
• プレウォーミング(Provisioned Concurrency)は使用しない
• 処理時間(Duration)とコールドスタートの所要時間(Init Duration)をCloudWatch Logs Insightsで集計
• CloudWatchで以下メトリクスを確認
  • RDS Proxyの現在のクライアント接続の数(ClientConnections)
  • RDS Proxyの現在のデータベース接続の数(DatabaseConnections)
  • RDS Proxyの現在ピン留めされているデータベース接続の数(DatabaseConnectionsCurrentlySessionPinned)
  • Lambda関数のイベントを処理している関数インスタンスの数(ConcurrentExecutions)
• Aurora DBクラスターはシングルAZ構成
• Lambda関数、RDS ProxyはマルチAZ構成

計測パターン

計測パターンは以下の4つです。

1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行
2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行
3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行
4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行

直列実行 VS 並列実行だとウォームスタートとコールドスタートの差で勝負にならないので、直列実行 VS 並列実行というよりも直列実行内、並列実行内で比較する形をとります。

また、各パターンの計測する際は各パターン毎に準備したステートマシンを実行して計測します。

// State Machine Tasks
const patternDbConnectTasks = [
  new tasks.LambdaInvoke(this, "Pattern1DbConnectTask", {
    lambdaFunction: dbAccessDbConnectOutsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.REQUEST_RESPONSE,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
  new tasks.LambdaInvoke(this, "Pattern2DbConnectTask", {
    lambdaFunction: dbAccessDbConnectInsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.REQUEST_RESPONSE,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
  new tasks.LambdaInvoke(this, "Pattern3DbConnectTask", {
    lambdaFunction: dbAccessDbConnectOutsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.EVENT,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
  new tasks.LambdaInvoke(this, "Pattern4DbConnectTask", {
    lambdaFunction: dbAccessDbConnectInsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.EVENT,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
];

// State Machine
patternDbConnectTasks.forEach((patternDbConnectTask, index) => {
  const createNumberArrayTask = new tasks.LambdaInvoke(
    this,
    `Pattern${index + 1}CreateNumberArrayTask`,
    {
      lambdaFunction: createNumberArrayFunction,
      payload: sfn.TaskInput.fromObject({
        number: sfn.JsonPath.stringAt("$.numberForInputMap"),
      }),
    }
  );

  const map = new sfn.Map(this, `Pattern${index + 1}MapState`, {
    maxConcurrency: index < 2 ? 1 : 0,
    itemsPath: sfn.JsonPath.stringAt("$.Payload.numberArray"),
  });

  new sfn.StateMachine(this, `Pattern${index + 1}StateMachine`, {
    definition: createNumberArrayTask
      .next(map.iterator(patternDbConnectTask))
      .next(new sfn.Succeed(this, `Pattern${index + 1}SuccessState`)),
    logs: {
      destination: stateMachineLogGroup,
      level: sfn.LogLevel.ALL,
    },
    tracingEnabled: true,
  });
});

100回Lambda関数を直列 or 並列実行したい場合は、ステートマシンに以下のJSONを渡します。

{
  "numberForInputMap": 100
}

CloudWatch Logs Insightsのクエリ

各パターン実行後に以下のCloudWatch Logs Insightsのクエリを実行して集計します。

filter @type = "REPORT"
| stats 
  avg(@duration) as duration_avg, 
  max(@duration) as duration_max,  
  min(@duration) as duration_min,  
  pct(@duration, 25) as duration_pct25,    
  pct(@duration, 50) as duration_pct50,    
  pct(@duration, 75) as duration_pct75,    
  count(@duration) as duration_count,     
  avg(@initDuration) as initDuration_avg, 
  max(@initDuration) as initDuration_max,  
  min(@initDuration) as initDuration_min,  
  pct(@initDuration, 25) as initDuration_pct25,    
  pct(@initDuration, 50) as initDuration_pct50,    
  pct(@initDuration, 75) as initDuration_pct75,    
  count(@initDuration) as initDuration_count     
| display 
  duration_avg,
  duration_max,
  duration_min,
  duration_pct25,
  duration_pct50,
  duration_pct75,
  duration_count,
  initDuration_avg,
  initDuration_max,
  initDuration_min,
  initDuration_pct25,
  initDuration_pct50,
  initDuration_pct75,
  initDuration_count

CloudWatch Logs Insights のクエリ構文は以下AWS公式ドキュメントをご覧ください。

各パターン終了毎にDBで行う作業

各パターン終了毎にDBで行う作業は以下の通りです。EC2インスタンスからRDS Porxyを経由せずAurora DBクラスターに接続してテーブルをクリアしたり、コネクションを削除したりします。

# Secrets ManagerからAurora DBクラスターのシークレットを取得
$ get_secrets_value=$(aws secretsmanager get-secret-value \
    --secret-id prd-db-cluster/AdminLoginInfo \
    --region us-east-1 \
    | jq -r .SecretString)

# シークレットを環境変数にセット
$ export PGHOST=$(echo "${get_secrets_value}" | jq -r .host)
$ export PGPORT=$(echo "${get_secrets_value}" | jq -r .port)
$ export PGDATABASE=$(echo "${get_secrets_value}" | jq -r .dbname)
$ export PGUSER=$(echo "${get_secrets_value}" | jq -r .username)
$ export PGPASSWORD=$(echo "${get_secrets_value}" | jq -r .password)

# Aurora DBクラスターに接続
$ psql

# テーブルを一度削除する
=> DROP TABLE test_table;

# テーブルを作成し直す
=> CREATE TABLE test_table (
    id SERIAL NOT NULL,
    name VARCHAR(255) NOT NULL,
    created_at TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
    PRIMARY KEY (id)
);

# 自分以外のコネクションを確認する
=> SELECT *
     FROM pg_stat_activity
   WHERE datname = 'testDB'
     AND pid <> pg_backend_pid();

# 自分以外のコネクションを切断する
=> SELECT pg_terminate_backend(pid)
     FROM pg_stat_activity
   WHERE datname = 'testDB'
     AND pid <> pg_backend_pid();

パターン1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行

まず、RDS Proxyの接続をhandlerの外側で実行するLambda関数を直列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

X-Rayトレースからタイムラインを確認すると、確かに直列で実行されていることが確認できます。

実行時のCloudWatchメトリクスは以下のようになっていました。

ClientConnectionsとDatabaseConnectionsは共に1であることからRDS Proxyへのコネクションを使い回していることが分かります。

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド	値
duration_avg	45.8541
duration_max	237.3
duration_min	13.29
duration_pct25	23.33
duration_pct50	34.88
duration_pct75	51.42
duration_count	100
initDuration_avg	696.14
initDuration_max	696.14
initDuration_min	696.14
initDuration_pct25	696.14
initDuration_pct50	696.14
initDuration_pct75	696.14
initDuration_count	1

initDuration_countが1になっていることからコールドスタートになったのは一回のみだったことが分かります。

パターン2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行

続いて、RDS Proxyの接続をhandlerの内側で実行するLambda関数を直列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

X-Rayトレースからタイムラインを確認すると、確かに直列で実行されていることが確認できます。

実行時のCloudWatchメトリクスは以下のようになっていました。

ClientConnectionsとDatabaseConnectionsは共に1であることからRDS Proxyへのコネクションを使い回していることが分かります。

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド	値
duration_avg	119.3956
duration_max	261.13
duration_min	82.56
duration_pct25	94.8905
duration_pct50	105.2851
duration_pct75	124.7844
duration_count	100
initDuration_avg	690.17
initDuration_max	690.17
initDuration_min	690.17
initDuration_pct25	690.17
initDuration_pct50	690.17
initDuration_pct75	690.17
initDuration_count	1

initDuration_countが1になっていることからコールドスタートになったのは一回のみだったことが分かります。

パターン3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行

続いて、RDS Proxyの接続をhandlerの外側で実行するLambda関数を並列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

X-Rayトレースからタイムラインを確認すると、確かに並列で実行されていることが確認できます。

実行時のCloudWatchメトリクスは以下のようになっていました。

Lambda関数が最大33多重で実行され、Lambda関数からRDS Proxyへのコネクションが19個あることが分かります。

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド	値
duration_avg	113.3586
duration_max	341.75
duration_min	25.12
duration_pct25	61.7404
duration_pct50	97.3888
duration_pct75	146.7171
duration_count	100
initDuration_avg	801.1223
initDuration_max	1273.24
initDuration_min	616.83
initDuration_pct25	729.95
initDuration_pct50	794.79
initDuration_pct75	842.5
initDuration_count	30

initDuration_countが30になっていることから30回コールドスタートが発生したことが分かります。

パターン4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行

最後に、RDS Proxyの接続をhandlerの内側で実行するLambda関数を並列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

X-Rayトレースからタイムラインを確認すると、確かに並列で実行されていることが確認できます。

実行時のCloudWatchメトリクスは以下のようになっていました。

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド	値
duration_avg	245.7216
duration_max	479.79
duration_min	93.94
duration_pct25	164.38
duration_pct50	222.96
duration_pct75	321.28
duration_count	100
initDuration_avg	666.3295
initDuration_max	747.01
initDuration_min	569.76
initDuration_pct25	643.28
initDuration_pct50	669.78
initDuration_pct75	687.03
initDuration_count	43

initDuration_countが43になっていることから43回コールドスタートが発生したことが分かります。

各パターンの結果比較

各パターンの結果比較します。

フィールド	パターン1	パターン2	パターン3	パターン4
duration_avg	45.8541	119.3956	113.3586	245.7216
duration_max	237.3	261.13	341.75	479.79
duration_min	13.29	82.56	25.12	93.94
duration_pct25	23.33	94.8905	61.7404	164.38
duration_pct50	34.88	105.2851	97.3888	222.96
duration_pct75	51.42	124.7844	146.7171	321.28
duration_count	100	100	100	100
initDuration_avg	696.14	690.17	801.1223	666.3295
initDuration_max	696.14	690.17	1273.24	747.01
initDuration_min	696.14	690.17	616.83	569.76
initDuration_pct25	696.14	690.17	729.95	643.28
initDuration_pct50	696.14	690.17	794.79	669.78
initDuration_pct75	696.14	690.17	842.5	687.03
initDuration_count	1	1	30	43

直列実行内、並列実行内で見比べると、duration_から始まる項目はRDS Proxyの接続をhandlerの外側で実行するLambda関数の方が処理時間が短いですね。

また、直列実行と並列実行で比較すると、ウォームスタートの差で直列実行の方が処理時間が短くなっていることも分かります。

ただし、各パターンのステートマシンの開始から終了までの時間を比較すると、直列実行よりも並列実行の方が圧倒的に短いことが分かります。並列実行の場合はLambda関数が30多重以上で実行されていたので、ウォームスタートの差が全体の処理完了までに与える影響を小さくしていたと判断できます。

パターン	ステートマシンの開始から終了までの時間
パターン1	24秒
パターン2	30秒
パターン3	4秒
パターン4	4秒

パフォーマンスを優先するならRDS Proxyの接続を使い回した方が良さそう

Lambda関数のhandlerの外側でRDS Proxyの接続をした場合の処理時間を計測してみました。

Lambda関数のhandlerの外側でRDS Proxyに接続することで、RDS Proxyへのコネクションを使い回すことができ、後続のLambda関数の処理時間を減らすことが確認できました。

Lambda関数のhandlerの外側でRDS Proxyの接続をする場合の注意点は接続を確立したままになる点です。そのため、長時間接続が放置されないようにアイドルクライアントの接続タイムアウトを適切な時間にする必要があります。(デフォルトは30分で最大8時間)

この記事が誰かの助けになれば幸いです。

以上、AWS事業本部 コンサルティング部の のんピ(@non____97)でした!